Add basic logging #396
Add basic logging #396
Conversation
| @@ -326,17 +326,26 @@ async def _handle_execution( | |||
| ) | |||
| except SmithyRetryException: | |||
| raise context_with_response.response | |||
| logger.debug( | |||
| "Retry needed. Attempting request #%s in %s seconds.", | |||
There was a problem hiding this comment.
Does retry_count start at 0 or 1 on our first call? i.e. is the first log message request 1 or 2?
There was a problem hiding this comment.
retry_count starts at 0. In the case where we need to retry a request, this get's increased to 1 before this log message. I'm adding 1 to this value to represent the number of the next attempt.
Here are our docs on retry_count:
retry_count: int
"""Retry count is the total number of attempts minus the initial attempt."""Here is an example of the first log message that gets printed when testing this:
DEBUG:bedrock_runtime.client:Retry needed. Attempting request #2 in 0.012663600881869781 seconds.
There was a problem hiding this comment.
Ok if the first log starts at 2, then this probably fine. I would say let's constrain the formatting a little though for seconds. Something like %.3f (or 4) should work to give us enough relevant information. I don't think we need full precision for this.
| await sleep(retry_token.retry_delay) | ||
| current_body = context_with_transport_request.transport_request.body | ||
| if (seek := getattr(current_body, "seek", None)) is not None: | ||
| await seek(0) | ||
| else: | ||
| # Step 8: Invoke record_success | ||
| logger.debug( | ||
| "Attempt %s succeeded. Not retrying request.", |
There was a problem hiding this comment.
We should probably quantify what attempt succeeded, I don't know if there's enough context here to be immediately clear.
I'm also not sure if we need to log this at all as it may produce more noise than value. Generally we want to record exceptional cases rather than noting everything that happened.
| "Attempt %s succeeded. Not retrying request.", | |
| "Request attempt %s succeeded. Not retrying request.", |
| retry_strategy.record_success(token=retry_token) | ||
| break | ||
| except Exception as e: | ||
| if context.response is not None: | ||
| logger.exception(f"Exception occurred while handling: {context.response}") | ||
| logger.exception("Exception occurred while handling: %s", context.response) |
There was a problem hiding this comment.
What gets logged with this? Do we have an example response payload?
There was a problem hiding this comment.
Yup, here is an example response:
ERROR:bedrock_runtime.client:Exception occurred while handling: Missing Authentication Token
| endpoint_resolver_parameters = StaticEndpointParams(uri=config.endpoint_uri) | ||
| logger.debug("Calling endpoint resolver with parameters: %s", endpoint_resolver_parameters) |
There was a problem hiding this comment.
We may need to rationalize this against Alex's other Endpoint work. I hope we don't need to add different log statements for each endpoint resolver.
There was a problem hiding this comment.
Yeah - I'm planning on doing a small refactor of the endpoint generator so that this code wouldn't be duplicated between them. (IE - the only thing that should be different between different endpoint generators is the parameter classes and how they are constructed)
There was a problem hiding this comment.
See refactoring: 2a4e6f0
This should play nicely with the logging above.
| logger.debug("HTTP request to sign: %s", context.transport_request) | ||
| logger.debug( | ||
| "Signer properties: %s", | ||
| auth_option.signer_properties | ||
| ) |
There was a problem hiding this comment.
I can build this to check but if you have a quick answer, what does the output of these look like? I haven't checked our repr's for them.
| @@ -229,7 +229,7 @@ async def _handle_execution( | |||
| event_response_deserializer: DeserializeableShape | None = None, | |||
| ${/hasEventStream} | |||
| ) -> Output: | |||
| logger.debug(f"Making request for operation {operation_name} with parameters: {input}") | |||
| logger.debug('Making request for operation "%s" with parameters: %s', operation_name, input) | |||
There was a problem hiding this comment.
Example:
DEBUG:bedrock_runtime.client:Making request for operation "Converse" with parameters: ConverseInput(model_id='amazon.titan-text-express-v1', messages=[Message(role='user', content=[ContentBlockText(value='Create a list of 3 best songs from the 1990s')])], system=None, inference_config=None, tool_config=None, guardrail_config=None, additional_model_request_fields=None, prompt_variables=None, additional_model_response_field_paths=None, request_metadata=None, performance_config=None)
| logger.debug("HTTP request config: %s", request_config) | ||
| logger.debug("Sending HTTP request: %s", context_with_response.transport_request) |
There was a problem hiding this comment.
Example:
DEBUG:bedrock_runtime.client:HTTP request config: HTTPRequestConfiguration(read_timeout=None)
DEBUG:bedrock_runtime.client:Sending HTTP request: HTTPRequest(destination=URI(scheme='https', username=None, password=None, host='bedrock-runtime.us-east-1.amazonaws.com', port=None, path='/model/amazon.titan-text-express-v1/converse', query='', fragment=None), method='POST', fields=Fields(OrderedDict({'content-type': Field(name='Content-Type', value=['application/json'], kind=<FieldPosition.HEADER: 0>), 'content-length': Field(name='Content-Length', value=['98'], kind=<FieldPosition.HEADER: 0>)})))
There was a problem hiding this comment.
I may need to tweak our reprs for fields and URIs so they're more readable. What we have now isn't great for logging.
| context_with_response._transport_response = await config.http_client.send( | ||
| request=context_with_response.transport_request, | ||
| request_config=request_config, | ||
| ) | ||
| logger.debug("Received HTTP response: %s", context_with_response.transport_response) |
There was a problem hiding this comment.
Example:
DEBUG:bedrock_runtime.client:Received HTTP response: HTTPResponse(status=403, fields=Fields(OrderedDict({'date': Field(name='Date', value=['Fri, 28 Feb 2025 18:54:22 GMT'], kind=<FieldPosition.HEADER: 0>), 'content-type': Field(name='Content-Type', value=['application/json'], kind=<FieldPosition.HEADER: 0>), 'content-length': Field(name='Content-Length', value=['42'], kind=<FieldPosition.HEADER: 0>), 'connection': Field(name='Connection', value=['keep-alive'], kind=<FieldPosition.HEADER: 0>), 'x-amzn-requestid': Field(name='x-amzn-RequestId', value=['af2aa5a0-aeae-406b-8082-c131293508e3'], kind=<FieldPosition.HEADER: 0>), 'x-amzn-errortype': Field(name='x-amzn-ErrorType', value=['MissingAuthenticationTokenException:http://internal.amazon.com/coral/com.amazon.coral.service/'], kind=<FieldPosition.HEADER: 0>)})), reason='Forbidden')
Overview
This PR adds basic logging for request and response information while transitioning to lazy string formatting. This approach deers the construction of log messages until they are actually needed, improving performance and consistency.
Why avoid f-strings in logging?
Using f-strings require Python to evaluate their expressions immediately, meaning that the log message is fully formatted regardless of whether it will be output (e.g., if the log level filters it out). Customers who don't configure logs would still experience the performance hit that comes with evaluating log statements.
TODO
By submitting this pull request, I confirm that you can use, modify, copy, and redistribute this contribution, under the terms of your choice.